Skip to content

Conversation

@rustyrussell
Copy link
Contributor

@rustyrussell rustyrussell commented Jul 9, 2025

FIRST FLAKE

We get a unilateral close if the blocks come too fast:

>       l2.daemon.wait_for_log(r'CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')

tests/test_splicing.py:96:
...
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile('CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')]" in logs.

Here:

lightningd-2 2025-07-08T12:08:30.430Z DEBUG   lightningd: Adding block 114: 542499dfc63bc94c0ba0a3d81bdaff07ab73ba9aebddd4c2ae4b2e0c1e8bd15f
...
lightningd-2 2025-07-08T12:08:30.459Z UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Peer permanent failure in CHANNELD_AWAITING_SPLICE: Fulfilled HTLC 1 RCVD_REMOVE_REVOCATION cltv11 4 hit deadline (reason=protocol)
lightningd-2 2025-07-08T12:08:30.469Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#1: Status closed, but not exited. Killing
lightningd-2 2025-07-08T12:08:30.475Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_AWAITING_SPLICE to AWAITING_UNILATERAL

SECOND FLAKE

>       l1.rpc.fundchannel(l2.info['id'], CHANNEL_SIZE)

tests/test_connection.py:667:
...
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: fundchannel, payload: {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'amount': 50000, 'announce': True}, error: {'code': -1, 'message': 'Disconnected', 'data': {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'method': 'openchannel_update'}}

What happens here is complicated.

  1. dualopend never processes the WIRE_COMMITMENT_SIGNED message, meaning it doesn't consider it worth
    trying to reconnect.
  2. Normally, on disconnect, we give subds time to process packets and then notice the disconnect.
  3. But, if we can another connection, we terminate the (old) subds immediately.
  4. When lightningd transitions the channel from DUALOPEND_OPEN_INIT to DUALOPEND_OPEN_COMMIT_READY,
    it tells connectd this peer is important.
  5. Normally, this causes a reconnect one second after hangup.
  6. However, if we've already disconnected, it makes connectd reconnect immediately. This causes
    the test flake, if dualopend hasn't processed the message, and thus changed the state to
    DUALOPEND_OPEN_COMMITTED: we don't reconnect and instead fail the fundchannel() call.

Changelog-None

We get a unilateral close if the blocks come too fast:

```
>       l2.daemon.wait_for_log(r'CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')

tests/test_splicing.py:96:
...
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile('CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')]" in logs.
```

Here:

```
lightningd-2 2025-07-08T12:08:30.430Z DEBUG   lightningd: Adding block 114: 542499dfc63bc94c0ba0a3d81bdaff07ab73ba9aebddd4c2ae4b2e0c1e8bd15f
...
lightningd-2 2025-07-08T12:08:30.459Z UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Peer permanent failure in CHANNELD_AWAITING_SPLICE: Fulfilled HTLC 1 RCVD_REMOVE_REVOCATION cltv11 4 hit deadline (reason=protocol)
lightningd-2 2025-07-08T12:08:30.469Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#1: Status closed, but not exited. Killing
lightningd-2 2025-07-08T12:08:30.475Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_AWAITING_SPLICE to AWAITING_UNILATERAL
```

Signed-off-by: Rusty Russell <[email protected]>
@rustyrussell rustyrussell added this to the v25.09 milestone Jul 9, 2025
@rustyrussell rustyrussell requested review from ddustin and sangbida July 9, 2025 02:05
@rustyrussell rustyrussell changed the title pytest: fix flake in test_splicing_rbf pytest: fix flakes in test_splicing_rbf and test_reconnect_signed Jul 9, 2025
```
>       l1.rpc.fundchannel(l2.info['id'], CHANNEL_SIZE)

tests/test_connection.py:667:
...
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: fundchannel, payload: {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'amount': 50000, 'announce': True}, error: {'code': -1, 'message': 'Disconnected', 'data': {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'method': 'openchannel_update'}}
```

What happens here is complicated.

1. dualopend never processes the WIRE_COMMITMENT_SIGNED message, meaning it doesn't consider it worth
   trying to reconnect.
2. Normally, on disconnect, we give subds time to process packets and then notice the disconnect.
3. But, if we can another connection, we terminate the (old) subds immediately.
4. When lightningd transitions the channel from DUALOPEND_OPEN_INIT to DUALOPEND_OPEN_COMMIT_READY,
   it tells connectd this peer is important.
5. Normally, this causes a reconnect one second after hangup.
6. However, if we've already disconnected, it makes connectd reconnect immediately.  This causes
   the test flake, if dualopend hasn't processed the message, and thus changed the state to
   DUALOPEND_OPEN_COMMITTED: we don't reconnect and instead fail the fundchannel() call.

Signed-off-by: Rusty Russell <[email protected]>
Copy link
Collaborator

@ddustin ddustin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The splicing test update LGTM, ack 19ae86f 👍

l1.rpc.pay(inv['bolt11'])

# Make sure l1 doesn't unilateral close if HTLC hasn't completely settled before deadline.
wait_for(lambda: only_one(l1.rpc.listpeerchannels()['channels'])['htlcs'] == [])
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah cool didn't know we had a way to do this 👍

@rustyrussell rustyrussell changed the title pytest: fix flakes in test_splicing_rbf and test_reconnect_signed pytest: fix flakes in test_splicing_rbf, test_reconnect_signed, test_htlc_no_force_close Jul 10, 2025
@rustyrussell rustyrussell enabled auto-merge (rebase) July 10, 2025 06:46
l3 closes with l2 unilaterally, but l2 sends l1 the channel_announce after
that, when it has never seen it before.  The solution is to wait until
l1 has seen the channel before we start the rest of the test:

```
E           ValueError:
E           Node errors:
E            - lightningd-2: had warning messages
E            - lightningd-1: had bad gossip messages
...
lightningd-2 2025-07-09T07:55:59.778Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_in WIRE_WARNING
lightningd-2 2025-07-09T07:55:59.778Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: Received WIRE_WARNING: WARNING: channel_announcement: no unspent txout 103x1x0
lightningd-1 2025-07-09T07:55:59.781Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-channeld-chan#1: billboard: Channel ready for use.
lightningd-1 2025-07-09T07:55:59.782Z TRACE   gossipd: channel_announcement: got reply for 103x1x0...
lightningd-1 2025-07-09T07:55:59.782Z TRACE   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-gossipd: Bad gossip order: channel_announcement: no unspent txout 103x1x0
```

Signed-off-by: Rusty Russell <[email protected]>
Sometimes the feerate is 5 too high.  But without seeing the actual txs it's
looking at, it's hard to know why.

```
actual_feerate = 13005.66942869603, expected_feerate = 13000

    def check_feerate(nodes, actual_feerate, expected_feerate):
        # Feerate can't be lower.
        assert actual_feerate > expected_feerate - 2
        if actual_feerate >= expected_feerate + 2:
            if any([did_short_sig(n) for n in nodes]):
                return
        # Use assert as it shows the actual values on failure
>       assert actual_feerate < expected_feerate + 2
E       AssertionError
```

Signed-off-by: Rusty Russell <[email protected]>
@rustyrussell rustyrussell merged commit 725c417 into ElementsProject:master Jul 11, 2025
76 of 79 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants